Writing to a Log file

Question on writing to log file

 

The code that I am running writes data to an external text Log file.  There are a number of functions within this code that write to this Log file.  Issue is that the Log file is not written to properly in that it appears that the data written to by one file overwrites that of another file.  What also is confusing me is that the data that I expect to be written 1st is written last.  For example, the Main section of the code writes 10 lines to the Log file and one of the following executed functions writes 20 lines.  What shows up in the log appears to be the 20 lines of code from the 2nd write operation, except that the 1st 10 lines are from the 1st write (i.e., the 1st 10 lines of the Log file are as expected, but the 11th line is not the start of the 2nd write operation (the new 20 lines of text), but rather it starts at line 11 of the 20 lines if text that was written in).  I tried using the Append command instead of the Write command and results do not look as expected.

The following code is used.  Any suggestions?

 

Stream writetoFile

 

function 1

writetofile = write (outputfilename)

writetofile = write (outputfilename)

writetoFile << "Log file comment"

 

function 2

writetofile = write (outputfilename)

writetoFile << "Log file comment"

 

Main

writetofile = write (outputfilename)

writetoFile << "Log file comment"


Mike.P.Adams - Mon Feb 16 12:28:28 EST 2015

Re: Writing to a Log file
GregM_dxler - Mon Feb 16 12:45:17 EST 2015

Hi,

Get rid of all the writetofile = write(outputfilename) except the one in Main.

The write (filename) is what actually makes the output file and starts the stream.  From there on, when you want to write to the file, you just write to the stream using the << command.

It's also good practice to close the stream at the end.

Hope this helps,

Greg 

Re: Writing to a Log file
Mike.P.Adams - Mon Feb 16 14:17:05 EST 2015

GregM_dxler - Mon Feb 16 12:45:17 EST 2015

Hi,

Get rid of all the writetofile = write(outputfilename) except the one in Main.

The write (filename) is what actually makes the output file and starts the stream.  From there on, when you want to write to the file, you just write to the stream using the << command.

It's also good practice to close the stream at the end.

Hope this helps,

Greg 

thanks, Geg - making those changes worked!

Re: Writing to a Log file
Wolfgang Uhr - Tue Feb 17 02:28:20 EST 2015

Mike.P.Adams - Mon Feb 16 14:17:05 EST 2015

thanks, Geg - making those changes worked!

In case of a log file you should use flus(wirteofile) to make shure that the data is really stored. Otherwise the dxl script can crash and the log file may not contain the important very last data ...

Re: Writing to a Log file
Mathias Mamsch - Tue Feb 17 10:47:09 EST 2015

One more hint regarding logfiles: Do NOT try to "append" to the log file. While there is a perm for this, the problem is, that this perm leaks an object (Stream) in memory every time you call it, and this can make your DXL become extremely slow after a couple of 1000 leaks.  Regards, Mathias

Re: Writing to a Log file
WardEdwards - Wed Feb 18 09:04:29 EST 2015

Mathias Mamsch - Tue Feb 17 10:47:09 EST 2015

One more hint regarding logfiles: Do NOT try to "append" to the log file. While there is a perm for this, the problem is, that this perm leaks an object (Stream) in memory every time you call it, and this can make your DXL become extremely slow after a couple of 1000 leaks.  Regards, Mathias

HI,

Can you clarify what you mean by "append"?    and how big of a memory leak this is and what versions of Doors it impacts?

Re: Writing to a Log file
Mathias Mamsch - Wed Feb 18 09:40:46 EST 2015

WardEdwards - Wed Feb 18 09:04:29 EST 2015

HI,

Can you clarify what you mean by "append"?    and how big of a memory leak this is and what versions of Doors it impacts?

By append I mean the perm: 

Stream append (string)

or any other of the Stream perms: 

Stream read (string)
Stream read (string, int)
Stream read (Binary__)
Stream write (string)
Stream write (string, int)
Stream write (Binary__)
Stream append (Binary__)
Stream append (string, int)
Stream openpictfile (Object)
Stream openPictFile (Object)

Note that up to DOORS 9.6 there is no "delete (Stream)" perm, which means, once a file is opened the Stream object will stay alive forever. There is a "close(Stream)" perm, but that perm will only close the file, but not free the stream object (as it should).

To test this, run the following code: 

pragma runLim, 0

// Adapt this count, start small until you get reasoable times 
int GCOUNT = 30000 // adapt if times are to low / hight for your computer
int steps = 1000; 

void performWork () {
   Buffer buf = create(); 
   delete buf; 
}


void profile (string sMsg, int count, void func ()) { 
    int iStart = getTickCount_ (); 
    int i; for (i = 0; i < count; i++) func(); 
    int iEnd = getTickCount_ (); 
    print sMsg ": " (iEnd - iStart) " ms \n"
}


string sFilename = "C:\\temp\\test.txt"; 

int allocations = 0; 

profile ("Before allocations: ", GCOUNT , performWork)

for (allocations = steps; allocations < 20000; allocations += steps) {
      // Leak 1000 objects here ...
    int x; for (x = 0; x < steps; x++) {
             // Comment me out and the leak goes away...
             Stream strm = append(sFilename); close strm; 
      }
        profile ("After " allocations  " allocations: ", GCOUNT , performWork)
}

You will probably get something like this: 

Before allocations: : 47 ms 
After 1000 allocations: : 328 ms 
After 2000 allocations: : 577 ms 
After 3000 allocations: : 858 ms 
After 4000 allocations: : 1170 ms 
After 5000 allocations: : 1514 ms 
After 6000 allocations: : 1794 ms 
After 7000 allocations: : 2121 ms 
After 8000 allocations: : 2418 ms 
After 9000 allocations: : 2683 ms 
After 10000 allocations: : 2964 ms 
After 11000 allocations: : 3276 ms 
After 12000 allocations: : 3557 ms 
After 13000 allocations: : 3838 ms 
After 14000 allocations: : 4150 ms 
After 15000 allocations: : 4461 ms 
After 16000 allocations: : 4648 ms 
After 17000 allocations: : 4961 ms 
After 18000 allocations: : 5226 ms 
After 19000 allocations: : 5553 ms

Which means, that after writing 20000 lines of log, your DXL might have slowed down by the factor of 100 (!!). To see that this is really about the allocations of the streams, just comment out the Stream line. You will get no increase.

This topic has been disussed a lot in the forum. Just search for memory slow down leak, etc. You will find code to test for these kind of memory leaks.

Regards, Mathias

Re: Writing to a Log file
Mathias Mamsch - Wed Feb 18 09:41:27 EST 2015

Mathias Mamsch - Wed Feb 18 09:40:46 EST 2015

By append I mean the perm: 

Stream append (string)

or any other of the Stream perms: 

Stream read (string)
Stream read (string, int)
Stream read (Binary__)
Stream write (string)
Stream write (string, int)
Stream write (Binary__)
Stream append (Binary__)
Stream append (string, int)
Stream openpictfile (Object)
Stream openPictFile (Object)

Note that up to DOORS 9.6 there is no "delete (Stream)" perm, which means, once a file is opened the Stream object will stay alive forever. There is a "close(Stream)" perm, but that perm will only close the file, but not free the stream object (as it should).

To test this, run the following code: 

pragma runLim, 0

// Adapt this count, start small until you get reasoable times 
int GCOUNT = 30000 // adapt if times are to low / hight for your computer
int steps = 1000; 

void performWork () {
   Buffer buf = create(); 
   delete buf; 
}


void profile (string sMsg, int count, void func ()) { 
    int iStart = getTickCount_ (); 
    int i; for (i = 0; i < count; i++) func(); 
    int iEnd = getTickCount_ (); 
    print sMsg ": " (iEnd - iStart) " ms \n"
}


string sFilename = "C:\\temp\\test.txt"; 

int allocations = 0; 

profile ("Before allocations: ", GCOUNT , performWork)

for (allocations = steps; allocations < 20000; allocations += steps) {
      // Leak 1000 objects here ...
    int x; for (x = 0; x < steps; x++) {
             // Comment me out and the leak goes away...
             Stream strm = append(sFilename); close strm; 
      }
        profile ("After " allocations  " allocations: ", GCOUNT , performWork)
}

You will probably get something like this: 

Before allocations: : 47 ms 
After 1000 allocations: : 328 ms 
After 2000 allocations: : 577 ms 
After 3000 allocations: : 858 ms 
After 4000 allocations: : 1170 ms 
After 5000 allocations: : 1514 ms 
After 6000 allocations: : 1794 ms 
After 7000 allocations: : 2121 ms 
After 8000 allocations: : 2418 ms 
After 9000 allocations: : 2683 ms 
After 10000 allocations: : 2964 ms 
After 11000 allocations: : 3276 ms 
After 12000 allocations: : 3557 ms 
After 13000 allocations: : 3838 ms 
After 14000 allocations: : 4150 ms 
After 15000 allocations: : 4461 ms 
After 16000 allocations: : 4648 ms 
After 17000 allocations: : 4961 ms 
After 18000 allocations: : 5226 ms 
After 19000 allocations: : 5553 ms

Which means, that after writing 20000 lines of log, your DXL might have slowed down by the factor of 100 (!!). To see that this is really about the allocations of the streams, just comment out the Stream line. You will get no increase.

This topic has been disussed a lot in the forum. Just search for memory slow down leak, etc. You will find code to test for these kind of memory leaks.

Regards, Mathias

Note that by the way, you can circumvent these kinds of leaks by using "eval" ... If you need to use the Stream perms a lot! Regards, Mathias

Re: Writing to a Log file
Wolfgang Uhr - Wed Feb 18 11:55:11 EST 2015

Mathias Mamsch - Wed Feb 18 09:40:46 EST 2015

By append I mean the perm: 

Stream append (string)

or any other of the Stream perms: 

Stream read (string)
Stream read (string, int)
Stream read (Binary__)
Stream write (string)
Stream write (string, int)
Stream write (Binary__)
Stream append (Binary__)
Stream append (string, int)
Stream openpictfile (Object)
Stream openPictFile (Object)

Note that up to DOORS 9.6 there is no "delete (Stream)" perm, which means, once a file is opened the Stream object will stay alive forever. There is a "close(Stream)" perm, but that perm will only close the file, but not free the stream object (as it should).

To test this, run the following code: 

pragma runLim, 0

// Adapt this count, start small until you get reasoable times 
int GCOUNT = 30000 // adapt if times are to low / hight for your computer
int steps = 1000; 

void performWork () {
   Buffer buf = create(); 
   delete buf; 
}


void profile (string sMsg, int count, void func ()) { 
    int iStart = getTickCount_ (); 
    int i; for (i = 0; i < count; i++) func(); 
    int iEnd = getTickCount_ (); 
    print sMsg ": " (iEnd - iStart) " ms \n"
}


string sFilename = "C:\\temp\\test.txt"; 

int allocations = 0; 

profile ("Before allocations: ", GCOUNT , performWork)

for (allocations = steps; allocations < 20000; allocations += steps) {
      // Leak 1000 objects here ...
    int x; for (x = 0; x < steps; x++) {
             // Comment me out and the leak goes away...
             Stream strm = append(sFilename); close strm; 
      }
        profile ("After " allocations  " allocations: ", GCOUNT , performWork)
}

You will probably get something like this: 

Before allocations: : 47 ms 
After 1000 allocations: : 328 ms 
After 2000 allocations: : 577 ms 
After 3000 allocations: : 858 ms 
After 4000 allocations: : 1170 ms 
After 5000 allocations: : 1514 ms 
After 6000 allocations: : 1794 ms 
After 7000 allocations: : 2121 ms 
After 8000 allocations: : 2418 ms 
After 9000 allocations: : 2683 ms 
After 10000 allocations: : 2964 ms 
After 11000 allocations: : 3276 ms 
After 12000 allocations: : 3557 ms 
After 13000 allocations: : 3838 ms 
After 14000 allocations: : 4150 ms 
After 15000 allocations: : 4461 ms 
After 16000 allocations: : 4648 ms 
After 17000 allocations: : 4961 ms 
After 18000 allocations: : 5226 ms 
After 19000 allocations: : 5553 ms

Which means, that after writing 20000 lines of log, your DXL might have slowed down by the factor of 100 (!!). To see that this is really about the allocations of the streams, just comment out the Stream line. You will get no increase.

This topic has been disussed a lot in the forum. Just search for memory slow down leak, etc. You will find code to test for these kind of memory leaks.

Regards, Mathias

Better is to compare two versions which writes data to the file 

pragma runLim, 0// Adapt this count, start small until you get reasoable times 
int GCOUNT = 30000 // adapt if times are to low / hight for your computer
int steps = 1000;
bool bUseWrite = false;  // Change from false to true to use append ...

void performWork () {
    Buffer buf = create();    
 delete buf;
}

void profile (string sMsg, int count, void func ()) {
 int iStart = getTickCount_ ();
 int i; 
 for (i = 0; i < count; i++) func();     
 int iEnd = getTickCount_ ();
 print sMsg ": " (iEnd - iStart) " ms \n"
}

string sFilename = "C:\\temp\\test.txt";

int allocations = 0; 
profile ("Before allocations: ", GCOUNT , performWork);
Stream strmWrite;
if (bUseWrite) {
 strmWrite = write(sFilename);
}

for (allocations = steps; allocations < 20000; allocations += steps) {
 // Leak 1000 objects here ...    
 int x; 
 for (x = 0; x < steps; x++) {
  if (bUseWrite) {
   strmWrite << "123\n";
   flush(strmWrite);
  } else {
   // Comment me out and the leak goes away...
   Stream strm = append(sFilename);
   strm << "123\n";
   close strm;
  }
 }
 profile ("After " allocations  " allocations: ", GCOUNT , performWork)
}

 

Re: Writing to a Log file
GregM_dxler - Thu Feb 19 08:54:33 EST 2015

Wolfgang Uhr - Wed Feb 18 11:55:11 EST 2015

Better is to compare two versions which writes data to the file 

pragma runLim, 0// Adapt this count, start small until you get reasoable times 
int GCOUNT = 30000 // adapt if times are to low / hight for your computer
int steps = 1000;
bool bUseWrite = false;  // Change from false to true to use append ...

void performWork () {
    Buffer buf = create();    
 delete buf;
}

void profile (string sMsg, int count, void func ()) {
 int iStart = getTickCount_ ();
 int i; 
 for (i = 0; i < count; i++) func();     
 int iEnd = getTickCount_ ();
 print sMsg ": " (iEnd - iStart) " ms \n"
}

string sFilename = "C:\\temp\\test.txt";

int allocations = 0; 
profile ("Before allocations: ", GCOUNT , performWork);
Stream strmWrite;
if (bUseWrite) {
 strmWrite = write(sFilename);
}

for (allocations = steps; allocations < 20000; allocations += steps) {
 // Leak 1000 objects here ...    
 int x; 
 for (x = 0; x < steps; x++) {
  if (bUseWrite) {
   strmWrite << "123\n";
   flush(strmWrite);
  } else {
   // Comment me out and the leak goes away...
   Stream strm = append(sFilename);
   strm << "123\n";
   close strm;
  }
 }
 profile ("After " allocations  " allocations: ", GCOUNT , performWork)
}

 

I find it easier to save the data to a buffer and then save it to the file at the end instead of trying to write it as I go.  Doesn't this reduce the problem?  That way the outputting to a file is compartmentalize and it also seems to let the script run faster.

Greg

Re: Writing to a Log file
Mike.Scharnow - Thu Feb 19 09:13:13 EST 2015

GregM_dxler - Thu Feb 19 08:54:33 EST 2015

I find it easier to save the data to a buffer and then save it to the file at the end instead of trying to write it as I go.  Doesn't this reduce the problem?  That way the outputting to a file is compartmentalize and it also seems to let the script run faster.

Greg

well, yes, but if your script crashes for whatever reasons, your log file will never be written and you don't have any information on why or where your script crashed (and IMO that's one of the main reasons for creating log files)